Skip to content

Conversation

@agrobbin
Copy link
Contributor

What does this PR do?
Instead of using around_perform, we now do the same thing that Active Job itself does to tag logs with [ActiveJob], the job class name, and job ID, which is wrapping perform_now.

Motivation:
The current Active Job integration injects a log correlation tag into the logger via around_perform, which is too late to pick up the following logs:

[ActiveJob] [FooJob] [540c4718-6668-4f3c-9411-ca52a4cffd15] Performing FooJob (Job ID: 540c4718-6668-4f3c-9411-ca52a4cffd15) from Sidekiq(default) enqueued at 2025-09-26T02:17:44.160363327Z with arguments: #<GlobalID:0x00007f0fae88cb50 @uri=#<URI::GID gid://foo-rails/Foo/019983cf-8422-72d5-85b7-f3dc09a4887e>>
[ActiveJob] [FooJob] [540c4718-6668-4f3c-9411-ca52a4cffd15] Performed FooJob (Job ID: 540c4718-6668-4f3c-9411-ca52a4cffd15) from Sidekiq(default) in 990.29ms

Change log entry

Additional Notes:

How to test the change?
I looked for an existing test to exercise this, but was unable to find one, and didn't see any tests specifically related to Active Job itself.

@agrobbin agrobbin requested review from a team as code owners September 26, 2025 02:31
@agrobbin agrobbin requested a review from vpellan September 26, 2025 02:31
@github-actions github-actions bot added integrations Involves tracing integrations tracing labels Sep 26, 2025
@vpellan
Copy link
Contributor

vpellan commented Oct 10, 2025

Hey @agrobbin ! Thanks for your contribution ! Just a heads up to tell you that I will look at this pull request next week as soon as possible !

@vpellan
Copy link
Contributor

vpellan commented Oct 13, 2025

Hey @agrobbin ! Unfortunately this change does not work with Rails < 6.0 (which we still support). It seems that perform_now is called before we start a trace, meaning that the trace_id and the span_id on the logs will be set to 0.
You can test it by using the ruby_2.7_rails5_postgres_sidekiq gemfile and running rspec spec/datadog/tracing/contrib/rails/rails_active_job_spec.rb:211 (you don't actually need sidekiq for this test, it's just that parts of this spec that requires it)
Is this something you want to investigate ?

@agrobbin agrobbin force-pushed the active-job-log-injection branch from 7964aff to 7acecb3 Compare October 13, 2025 16:22
@agrobbin
Copy link
Contributor Author

@vpellan interesting! I looked at the source and it seems the logging of Active Job itself was reimplemented in Rails 6+, so it makes sense that this wouldn't work quite the same in those versions.

I've introduced branching to only wrap the full execution in Rails 6+, which should ensure that test passes again!

@vpellan
Copy link
Contributor

vpellan commented Oct 17, 2025

Hey @agrobbin ! Thanks for the fix ! I left a small comment but except that, LGTM ! We need to run these changes on our latest CI before merging, would you agree to give us the authorization to merge master on your branch ? So we don't have to bother you each time we need to run the CI. Thanks !

@agrobbin agrobbin force-pushed the active-job-log-injection branch from 7acecb3 to cfe8ae0 Compare October 17, 2025 11:52
@agrobbin
Copy link
Contributor Author

Updated! I also rebased off of the latest master. If things change on master before this can be merged, feel free to merge it into this branch (I've checked the "allow edits ... by maintainers" box).

The current Active Job integration injects a log correlation tag into the logger via `around_perform`, which is too late to pick up the following logs:

```
[ActiveJob] [FooJob] [540c4718-6668-4f3c-9411-ca52a4cffd15] Performing FooJob (Job ID: 540c4718-6668-4f3c-9411-ca52a4cffd15) from Sidekiq(default) enqueued at 2025-09-26T02:17:44.160363327Z with arguments: #<GlobalID:0x00007f0fae88cb50 @uri=#<URI::GID gid://foo-rails/Foo/019983cf-8422-72d5-85b7-f3dc09a4887e>>
[ActiveJob] [FooJob] [540c4718-6668-4f3c-9411-ca52a4cffd15] Performed FooJob (Job ID: 540c4718-6668-4f3c-9411-ca52a4cffd15) from Sidekiq(default) in 990.29ms
```

Instead of using `around_perform`, we now do the same thing that [Active Job itself](https://github.com/rails/rails/blob/v8.0.3/activejob/lib/active_job/logging.rb#L31-L33) does to tag logs with `[ActiveJob]`, the job class name, and job ID, which is wrapping `perform_now`.

Note that this only works on Active Job 6+, so we inject different log correlation logic depending on the Active Job version.
@agrobbin agrobbin force-pushed the active-job-log-injection branch from cfe8ae0 to 6a1f75f Compare October 17, 2025 14:25
@vpellan vpellan merged commit 66d9ae9 into DataDog:master Oct 21, 2025
730 of 745 checks passed
@vpellan
Copy link
Contributor

vpellan commented Oct 21, 2025

Thank you very much for your contribution, this will be available in the next release !

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

integrations Involves tracing integrations tracing

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants